**** dT 0.000 * top TEST ../../../../bin/vinyltest/tests/o00005.vtc starting **** top extmacro def pkg_version=trunk **** top extmacro def pkg_branch=trunk **** top extmacro def pwd=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest **** top extmacro def date(...) **** top extmacro def string(...) **** top extmacro def localhost=127.0.0.1 **** top extmacro def bad_backend=127.0.0.1:55102 **** top extmacro def listen_addr=127.0.0.1:0 **** top extmacro def bad_ip=192.0.2.255 **** top extmacro def topbuild=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub **** top extmacro def topsrc=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/../.. **** top macro def testdir=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/tests **** top macro def tmpdir=/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa **** top macro def vtcid=vtc.952676.692700fa **** dT 0.001 ** top === vtest "PROXY v2 TLV overflow" * top VTEST PROXY v2 TLV overflow ** top === feature ipv4 ** top === vinyl v1 -arg "-p pool_sess=0,0,0" -proto "PROXY" -vcl { **** dT 0.011 ** v1 Launch *** v1 CMD: cd ${pwd} && exec vinyld -d -n /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 60050' -P /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1/vinyld.pid -p vmod_path=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -p pool_sess=0,0,0 *** v1 CMD: cd /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest && exec vinyld -d -n /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -a '127.0.0.1:0',PROXY -M '127.0.0.1 60050' -P /tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1/vinyld.pid -p vmod_path=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -p pool_sess=0,0,0 **** dT 0.013 *** v1 PID: 952688 **** v1 macro def v1_pid=952688 **** v1 macro def v1_name=/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1 **** dT 0.055 *** v1 debug|Warning: mlock() of VSM failed: Not owner (1 *** v1 debug|) **** dT 0.058 *** v1 debug|Debug: Version: vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 *** v1 debug| *** v1 debug|Debug: *** v1 debug|Platform: -jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|200 292 *** v1 debug|----------------------------- *** v1 debug|Vinyl Cache CLI 1.0 *** v1 debug|----------------------------- *** v1 debug|-jsolaris,-sdefault,-sdefault,-hcritbit *** v1 debug|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 *** v1 debug| *** v1 debug|Type 'help' for command list. *** v1 debug|Type 'quit' to close CLI session. *** v1 debug|Type 'start' to launch worker process. *** v1 debug| **** dT 0.156 **** v1 CLIPOLL 1 0x1 0x0 0x0 *** v1 CLI connection fd = 4 *** v1 CLI RX 107 **** v1 CLI RX|opkcahamlqjbjdnphprqoidwvkmkkfqy **** v1 CLI RX| **** v1 CLI RX|Authentication required. **** v1 CLI TX|auth 759085cc77a1aeab5f6063a7791631ff8f8e7509a078bbfb0ef8dd01926c2c46 **** dT 0.157 *** v1 CLI RX 200 **** v1 CLI RX|----------------------------- **** v1 CLI RX|Vinyl Cache CLI 1.0 **** v1 CLI RX|----------------------------- **** v1 CLI RX|-jsolaris,-sdefault,-sdefault,-hcritbit **** v1 CLI RX|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4 **** v1 CLI RX| **** v1 CLI RX|Type 'help' for command list. **** v1 CLI RX|Type 'quit' to close CLI session. **** v1 CLI RX|Type 'start' to launch worker process. **** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P **** v1 CLI TX|vcl 4.1; **** v1 CLI TX| **** v1 CLI TX|\tbackend be none; **** v1 CLI TX| **** v1 CLI TX|%XJEIFLH|)Xspa8P **** dT 0.257 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.358 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.458 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.558 *** v1 vsl|No VSL chunk found (child not started ?) **** dT 0.628 *** v1 CLI RX 200 **** v1 CLI RX|Message from VCC-compiler: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|Message from C-compiler: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|cc: Warning: Option -fno-var-tracking-assignments passed to ld, if ld is invoked, ignored otherwise **** v1 CLI RX|"vgc.c", line 3146: warning: statement not reached (E_STATEMENT_NOT_REACHED) **** v1 CLI RX|Message from dlopen: **** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged **** v1 CLI RX|VCL compiled. **** v1 CLI TX|vcl.use vcl1 *** v1 CLI RX 200 **** v1 CLI RX|VCL 'vcl1' now active ** v1 Start **** v1 CLI TX|start **** dT 0.640 *** v1 debug|Debug: *** v1 debug|Child (952771) Started **** dT 0.669 *** v1 debug|Child launched OK **** dT 0.671 *** v1 CLI RX 200 *** v1 wait-running **** v1 CLI TX|status *** v1 debug|Info: Child (952771) said Child starts *** v1 debug| *** v1 debug|Info: Child (952771) said notice:\tlibumem was already found to be loaded *** v1 debug| *** v1 debug|Info: *** v1 debug|Child (952771) said Security: proc_setid missing, uid/gid unchanged *** v1 debug| *** v1 CLI RX 200 **** v1 CLI RX|Child in state running **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 41834 **** v1 CLI TX|debug.xid 1000 *** v1 CLI RX 200 **** v1 CLI RX|XID is 1000 chunk 1 **** v1 CLI TX|debug.listen_address *** v1 CLI RX 200 **** v1 CLI RX|a0 127.0.0.1 41834 ** v1 Listen on 127.0.0.1 41834 **** v1 macro def v1_addr=127.0.0.1 **** v1 macro def v1_port=41834 **** v1 macro def v1_sock=127.0.0.1:41834 **** v1 macro def v1_a0_addr=127.0.0.1 **** v1 macro def v1_a0_port=41834 **** v1 macro def v1_a0_sock=127.0.0.1:41834 **** dT 0.758 **** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1773725619.426658/vgc.so 1auto **** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1773725619.426658/vgc.so" as "vcl1" **** v1 vsl| 0 CLI - Rd vcl.use "vcl1" **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd start **** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting TCP_NODELAY for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPIDLE for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPCNT for a0=127.0.0.1:41834 **** v1 vsl| 0 Debug - sockopt: Setting TCP_KEEPINTVL for a0=127.0.0.1:41834 **** v1 vsl| 0 CLI - Wr 200 0 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 41834 **** v1 vsl| 0 CLI - Rd debug.xid 1000 **** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1 **** v1 vsl| 0 CLI - Rd debug.listen_address **** v1 vsl| 0 CLI - Wr 200 19 a0 127.0.0.1 41834 **** dT 0.771 ** top === logexpect l1 -v v1 -g raw { **** dT 0.772 ** l1 === expect * 1000 Begin "sess 0 PROXY" ** l1 === expect * 1000 ProxyGarbage "PROXY2: CRC error" ** top === client c1 { **** l1 begin| ** c1 Starting client *** l1 test | expect * 1000 Begin sess 0 PROXY ** c1 Waiting for client ** c1 Started on 127.0.0.1:41834 (1 iterations) *** c1 Connect to 127.0.0.1:41834 **** dT 0.773 *** c1 connected fd 19 from 127.0.0.1 51755 to 127.0.0.1:41834 ** c1 === sendhex { **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a 21 11 00 65 **** c1 sendhex| d9 46 b5 21 5f 8e a8 22 ed 96 01 bb 03 00 04 95 **** c1 sendhex| 03 ee 74 01 00 02 68 32 02 00 0a 68 6f 63 64 65 **** c1 sendhex| 74 2e 6e 65 74 20 00 3d 01 00 00 00 00 21 00 07 **** c1 sendhex| 54 4c 53 76 31 2e 33 25 00 05 45 43 32 35 36 24 **** c1 sendhex| 00 0a 52 53 41 2d 53 48 41 32 35 36 23 00 16 41 **** c1 sendhex| 45 41 44 2d 41 45 53 31 32 38 2d 47 43 4d 2d 53 **** c1 sendhex| 48 41 32 35 36 ** c1 === txreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === expect_close **** c1 Expecting close (fd = 19) **** c1 fd=19 EOF, as expected *** c1 closing fd 19 ** c1 Ending ** top === vinyl v1 -vsl_catchup **** dT 0.782 **** l1 match| 1000 Begin c sess 0 PROXY *** l1 test | expect * 1000 ProxyGarbage PROXY2: CRC error **** l1 match| 1000 ProxyGarbage c PROXY2: CRC error **** l1 done | **** dT 0.858 **** v1 vsl| 1000 Begin c sess 0 PROXY **** v1 vsl| 1000 SessOpen c 127.0.0.1 51755 a0 127.0.0.1 41834 1773725620.041928 16 **** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1000 Proxy c 2 217.70.181.33 60822 95.142.168.34 443 **** v1 vsl| 1000 ProxyGarbage c PROXY2: CRC error **** v1 vsl| 1000 SessClose c RX_JUNK 0.000 **** v1 vsl| 1000 End c **** dT 0.873 ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1001 Begin "sess 0 PROXY" ** l1 === expect * 1001 ProxyGarbage "PROXY2: TLV Dribble bytes" **** dT 0.874 ** top === client c1 { ** c1 Starting client **** l1 begin| *** l1 test | expect * 1001 Begin sess 0 PROXY ** c1 Waiting for client ** c1 Started on 127.0.0.1:41834 (1 iterations) *** c1 Connect to 127.0.0.1:41834 *** c1 connected fd 19 from 127.0.0.1 58719 to 127.0.0.1:41834 ** c1 === sendhex { **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a 21 11 00 67 **** c1 sendhex| d9 46 b5 21 5f 8e a8 22 ed 96 01 bb ff 00 04 95 **** c1 sendhex| 03 ee 74 01 00 02 68 32 02 00 0a 68 6f 63 64 65 **** c1 sendhex| 74 2e 6e 65 74 20 00 3d 01 00 00 00 00 21 00 07 **** c1 sendhex| 54 4c 53 76 31 2e 33 25 00 05 45 43 32 35 36 24 **** c1 sendhex| 00 0a 52 53 41 2d 53 48 41 32 35 36 23 00 16 41 **** c1 sendhex| 45 41 44 2d 41 45 53 31 32 38 2d 47 43 4d 2d 53 **** c1 sendhex| 48 41 32 35 36 ff ff ** c1 === txreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === expect_close **** c1 Expecting close (fd = 19) **** c1 fd=19 EOF, as expected *** c1 closing fd 19 ** c1 Ending ** top === vinyl v1 -vsl_catchup **** dT 0.884 **** l1 match| 1001 Begin c sess 0 PROXY *** l1 test | expect * 1001 ProxyGarbage PROXY2: TLV Dribble bytes **** l1 match| 1001 ProxyGarbage c PROXY2: TLV Dribble bytes **** l1 done | **** dT 0.958 **** v1 vsl| 1001 Begin c sess 0 PROXY **** v1 vsl| 1001 SessOpen c 127.0.0.1 58719 a0 127.0.0.1 41834 1773725620.143213 17 **** v1 vsl| 1001 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1001 Proxy c 2 217.70.181.33 60822 95.142.168.34 443 **** v1 vsl| 1001 ProxyGarbage c PROXY2: TLV Dribble bytes **** v1 vsl| 1001 SessClose c RX_JUNK 0.000 **** v1 vsl| 1001 End c **** dT 0.974 ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1002 Begin "sess 0 PROXY" ** l1 === expect * 1002 ProxyGarbage "PROXY2: TLV Length Error" **** dT 0.975 ** top === client c1 { ** c1 Starting client **** l1 begin| *** l1 test | expect * 1002 Begin sess 0 PROXY ** c1 Waiting for client ** c1 Started on 127.0.0.1:41834 (1 iterations) *** c1 Connect to 127.0.0.1:41834 *** c1 connected fd 19 from 127.0.0.1 59482 to 127.0.0.1:41834 ** c1 === sendhex { **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a 21 11 00 60 **** c1 sendhex| d9 46 b5 21 5f 8e a8 22 ed 96 01 bb ff 00 04 95 **** c1 sendhex| 03 ee 74 01 00 02 68 32 02 00 0a 68 6f 63 64 65 **** c1 sendhex| 74 2e 6e 65 74 20 00 3d 01 00 00 00 00 21 00 07 **** c1 sendhex| 54 4c 53 76 31 2e 33 25 00 05 45 43 32 35 36 24 **** c1 sendhex| 00 0a 52 53 41 2d 53 48 41 32 35 36 23 00 16 41 **** c1 sendhex| 45 41 44 2d 41 45 53 31 32 38 2d 47 43 4d 2d 53 **** c1 sendhex| 48 41 32 35 36 ** c1 === txreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === expect_close **** c1 Expecting close (fd = 19) **** c1 fd=19 EOF, as expected *** c1 closing fd 19 ** c1 Ending ** top === vinyl v1 -vsl_catchup **** dT 0.985 **** l1 match| 1002 Begin c sess 0 PROXY *** l1 test | expect * 1002 ProxyGarbage PROXY2: TLV Length Error **** l1 match| 1002 ProxyGarbage c PROXY2: TLV Length Error **** l1 done | **** dT 1.058 **** v1 vsl| 1002 Begin c sess 0 PROXY **** v1 vsl| 1002 SessOpen c 127.0.0.1 59482 a0 127.0.0.1 41834 1773725620.244145 18 **** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1002 Proxy c 2 217.70.181.33 60822 95.142.168.34 443 **** v1 vsl| 1002 ProxyGarbage c PROXY2: TLV Length Error **** v1 vsl| 1002 SessClose c RX_JUNK 0.000 **** v1 vsl| 1002 End c **** dT 1.075 ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === logexpect l1 -v v1 -g raw { ** l1 === expect * 1003 Begin "sess 0 PROXY" ** l1 === expect * 1003 ProxyGarbage "PROXY2: TLV Length Error" ** top === client c1 { ** c1 Starting client **** l1 begin| *** l1 test | expect * 1003 Begin sess 0 PROXY **** dT 1.076 ** c1 Waiting for client ** c1 Started on 127.0.0.1:41834 (1 iterations) *** c1 Connect to 127.0.0.1:41834 *** c1 connected fd 19 from 127.0.0.1 35610 to 127.0.0.1:41834 ** c1 === sendhex { **** c1 sendhex| 0d 0a 0d 0a 00 0d 0a 51 55 49 54 0a 21 11 00 65 **** c1 sendhex| d9 46 b5 21 5f 8e a8 22 ed 96 01 bb ff 00 04 95 **** c1 sendhex| 03 ee 74 01 00 02 68 32 02 00 0a 68 6f 63 64 65 **** c1 sendhex| 74 2e 6e 65 74 20 00 3c 01 00 00 00 00 21 00 07 **** c1 sendhex| 54 4c 53 76 31 2e 33 25 00 05 45 43 32 35 36 24 **** c1 sendhex| 00 0a 52 53 41 2d 53 48 41 32 35 36 23 00 16 41 **** c1 sendhex| 45 41 44 2d 41 45 53 31 32 38 2d 47 43 4d 2d 53 **** c1 sendhex| 48 41 32 35 36 ** c1 === txreq **** c1 txreq|GET / HTTP/1.1\r **** c1 txreq|Host: 127.0.0.1\r **** c1 txreq|User-Agent: c1\r **** c1 txreq|\r ** c1 === expect_close **** c1 Expecting close (fd = 19) **** c1 fd=19 EOF, as expected *** c1 closing fd 19 ** c1 Ending ** top === vinyl v1 -vsl_catchup **** dT 1.086 **** l1 match| 1003 Begin c sess 0 PROXY *** l1 test | expect * 1003 ProxyGarbage PROXY2: TLV Length Error **** l1 match| 1003 ProxyGarbage c PROXY2: TLV Length Error **** l1 done | **** dT 1.158 **** v1 vsl| 1003 Begin c sess 0 PROXY **** v1 vsl| 1003 SessOpen c 127.0.0.1 35610 a0 127.0.0.1 41834 1773725620.345077 16 **** v1 vsl| 1003 Debug c sockopt: SO_LINGER may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: Setting SO_KEEPALIVE for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: SO_SNDTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: SO_RCVTIMEO may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: TCP_NODELAY may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: TCP_KEEPIDLE may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: TCP_KEEPCNT may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Debug c sockopt: TCP_KEEPINTVL may be inherited for a0=127.0.0.1:41834 **** v1 vsl| 1003 Proxy c 2 217.70.181.33 60822 95.142.168.34 443 **** v1 vsl| 1003 ProxyGarbage c PROXY2: TLV Length Error **** v1 vsl| 1003 SessClose c RX_JUNK 0.000 **** v1 vsl| 1003 End c **** dT 1.176 ** top === logexpect l1 -wait ** l1 Waiting for logexp ** top === vinyl v1 -cliok "param.set workspace_session 384" **** v1 CLI TX|param.set workspace_session 384 *** v1 CLI RX 200 ** v1 CLI 200 ** top === vinyl v1 -stop ** v1 Stop **** v1 CLI TX|stop *** v1 debug|Debug: Stopping Child **** dT 1.259 **** v1 vsl| 0 CLI - EOF on CLI connection, worker stops **** dT 1.276 *** v1 debug|Info: Child (952771) said Child dies *** v1 debug|Info: Child (952771) ended **** dT 1.277 *** v1 debug|Debug: Child cleanup complete *** v1 debug| *** v1 CLI RX 200 *** v1 wait-stopped **** v1 CLI TX|status *** v1 CLI RX 200 **** v1 CLI RX|Child in state stopped ** top === vinyl v1 -cliok "param.set pool_sess 1,1,1" **** v1 CLI TX|param.set pool_sess 1,1,1 *** v1 CLI RX 200 ** v1 CLI 200 ** top === vinyl v1 -start ** v1 Start **** v1 CLI TX|start **** dT 1.291 *** v1 debug|Debug: *** v1 debug|Child (952811) Started **** dT 1.312 *** v1 debug|Error: Child failed on launch *** v1 debug| *** v1 debug|Info: Child (952811) said Child starts *** v1 debug|Info: *** v1 debug| *** v1 debug|Child (952811) said notice:\tlibumem was already found to be loaded *** v1 debug| *** v1 debug|Info: *** v1 debug| *** v1 debug|Child (952811) said Security: proc_setid missing, uid/gid unchanged *** v1 debug| **** dT 1.412 *** v1 debug|Error: Child (952811) died signal=6 *** v1 debug|Error: *** v1 debug|Child (952811) Panic at: Tue, 17 Mar 2026 05:33:40 GMT *** v1 debug|Wrong turn at ../../../../bin/vinyld/cache/cache_mempool.c:246: *** v1 debug|pthread_create(&mpl->thread, ((void *)0), mpl_guard, mpl) failed *** v1 debug|version = vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4, vrt api = 23.0 *** v1 debug|ident = -jsolaris,-sdefault,-sdefault,-hcritbit,ports *** v1 debug|now = 5937697.181126 (mono), 1773725620.579459 (real) *** v1 debug|Backtrace: *** v1 debug| 6d5a7d: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'vbt_execinfo+0x3d [0x6d5a7d] *** v1 debug| 6d5e21: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'VBT_format+0x41 [0x6d5e21] *** v1 debug| 5539f8: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pan_backtrace+0x58 [0x5539f8] *** v1 debug| 5540f9: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pan_ic+0x539 [0x5540f9] *** v1 debug| 6d43ac: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub *** v1 debug|/bin/vinyld/vinyld'VAS_Fail+0x8c [0x6d43ac] *** v1 debug| 545ed2: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'MPL_New+0x332 [0x545ed2] *** v1 debug| 57705f: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'SES_NewPool+0x15f [0x57705f] *** v1 debug| 555de9: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pool_mkpool+0x449 [0x555de9] *** v1 debug| 555eab: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pool_poolherder+0x6b [0x555eab] *** v1 debug| fffffc7fef2456e7: /lib/amd64/libc.so.1'_thrp_setup+0x77 [0xfffffc7fef2456e7] *** v1 debug| fffffc7fef245a30: /lib/amd64/libc.so.1'_lwp_start+0x0 [0xfffffc7fef245a30] *** v1 debug|errno = 11 (Resource temporarily unavailable) *** v1 debug|argv = { *** v1 debug| [0] = \"vinyld\", *** v1 debug| [1] = \"-d\", *** v1 debug| [2] = \"-n\", *** v1 debug| [3] = \"/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1\", *** v1 debug| [4] = \"-i\", *** v1 debug| [5] = \"v1\", *** v1 debug| [6] = \"-l\", *** v1 debug| [7] = \"2m\", *** v1 debug| [8] = \"-p\", *** v1 debug| [9] = \" *** v1 CLI RX 400 *** v1 debug|auto_restart=off\", *** v1 debug| [10] = \"-p\", *** v1 debug| [11] = \"syslog_cli_traffic=off\", *** v1 debug| [12] = \"-p\", *** v1 debug| [13] = \"thread_pool_min=10\", *** v1 debug| [14] = \"-p\", *** v1 debug| [15] = \"debug=+vtc_mode\", *** v1 debug| [16] = \"-p\", *** v1 debug| [17] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", *** v1 debug| [18] = \"-p\", *** v1 debug| [19] = \"h2_initial_window_size=1m\", *** v1 debug| [20] = \"-p\", *** v1 debug| [21] = \"h2_rx_window_low_water=64k\", *** v1 debug| [22] = \"-a\", *** v1 debug| [23] = \"127.0.0.1:0,PROXY\", *** v1 debug| [24] = \"-M\", *** v1 debug| [25] = \"127.0.0.1 60050\", *** v1 debug| [26] = \"-P\", *** v1 debug| [27] = \"/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1/vinyld.pid\", *** v1 debug| [28] = \"-p\", *** v1 debug| [29] = \"vmod_path=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs:\", *** v1 debug| [30] = \"-p\", *** v1 debug| [31] = \"pool_sess=0,0,0\", *** v1 debug|} *** v1 debug|pthread.self = 4 *** v1 debug|pthread.name = (pool_poolherder) *** v1 debug|thr.req = NULL *** v1 debug|thr.busyobj = NULL *** v1 debug|thr.worker = NULL *** v1 debug|vmods = { *** v1 debug|}, *** v1 debug|pools = { *** v1 debug|}, *** v1 debug| *** v1 debug| *** v1 debug|Debug: Child cleanup complete **** v1 CLI RX|Child failed on launch **** dT 1.422 ---- v1 CLI start command failed: 400 Child failed on launch * top RESETTING after ../../../../bin/vinyltest/tests/o00005.vtc ** v1 Wait **** v1 CLI TX|panic.show **** dT 1.423 *** v1 CLI RX 200 **** v1 CLI RX|Child (952811) Panic at: Tue, 17 Mar 2026 05:33:40 GMT **** v1 CLI RX|Wrong turn at ../../../../bin/vinyld/cache/cache_mempool.c:246: **** v1 CLI RX|pthread_create(&mpl->thread, ((void *)0), mpl_guard, mpl) failed **** v1 CLI RX|version = vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4, vrt api = 23.0 **** v1 CLI RX|ident = -jsolaris,-sdefault,-sdefault,-hcritbit,ports **** v1 CLI RX|now = 5937697.181126 (mono), 1773725620.579459 (real) **** v1 CLI RX|Backtrace: **** v1 CLI RX| 6d5a7d: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'vbt_execinfo+0x3d [0x6d5a7d] **** v1 CLI RX| 6d5e21: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'VBT_format+0x41 [0x6d5e21] **** v1 CLI RX| 5539f8: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pan_backtrace+0x58 [0x5539f8] **** v1 CLI RX| 5540f9: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pan_ic+0x539 [0x5540f9] **** v1 CLI RX| 6d43ac: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'VAS_Fail+0x8c [0x6d43ac] **** v1 CLI RX| 545ed2: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'MPL_New+0x332 [0x545ed2] **** v1 CLI RX| 57705f: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'SES_NewPool+0x15f [0x57705f] **** v1 CLI RX| 555de9: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pool_mkpool+0x449 [0x555de9] **** v1 CLI RX| 555eab: /tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyld/vinyld'pool_poolherder+0x6b [0x555eab] **** v1 CLI RX| fffffc7fef2456e7: /lib/amd64/libc.so.1'_thrp_setup+0x77 [0xfffffc7fef2456e7] **** v1 CLI RX| fffffc7fef245a30: /lib/amd64/libc.so.1'_lwp_start+0x0 [0xfffffc7fef245a30] **** v1 CLI RX|errno = 11 (Resource temporarily unavailable) **** v1 CLI RX|argv = { **** v1 CLI RX| [0] = \"vinyld\", **** v1 CLI RX| [1] = \"-d\", **** v1 CLI RX| [2] = \"-n\", **** v1 CLI RX| [3] = \"/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1\", **** v1 CLI RX| [4] = \"-i\", **** v1 CLI RX| [5] = \"v1\", **** v1 CLI RX| [6] = \"-l\", **** v1 CLI RX| [7] = \"2m\", **** v1 CLI RX| [8] = \"-p\", **** v1 CLI RX| [9] = \"auto_restart=off\", **** v1 CLI RX| [10] = \"-p\", **** v1 CLI RX| [11] = \"syslog_cli_traffic=off\", **** v1 CLI RX| [12] = \"-p\", **** v1 CLI RX| [13] = \"thread_pool_min=10\", **** v1 CLI RX| [14] = \"-p\", **** v1 CLI RX| [15] = \"debug=+vtc_mode\", **** v1 CLI RX| [16] = \"-p\", **** v1 CLI RX| [17] = \"vsl_mask=+Debug,+H2RxHdr,+H2RxBody\", **** v1 CLI RX| [18] = \"-p\", **** v1 CLI RX| [19] = \"h2_initial_window_size=1m\", **** v1 CLI RX| [20] = \"-p\", **** v1 CLI RX| [21] = \"h2_rx_window_low_water=64k\", **** v1 CLI RX| [22] = \"-a\", **** v1 CLI RX| [23] = \"127.0.0.1:0,PROXY\", **** v1 CLI RX| [24] = \"-M\", **** v1 CLI RX| [25] = \"127.0.0.1 60050\", **** v1 CLI RX| [26] = \"-P\", **** v1 CLI RX| [27] = \"/tmp/vtest.suncc12.6_m64_IPv4_uffix/_vtest_tmp/vtc.952676.692700fa/v1/vinyld.pid\", **** v1 CLI RX| [28] = \"-p\", **** v1 CLI RX| [29] = \"vmod_path=/tmp/vtest.suncc12.6_m64_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs:\", **** v1 CLI RX| [30] = \"-p\", **** v1 CLI RX| [31] = \"pool_sess=0,0,0\", **** v1 CLI RX|} **** v1 CLI RX|pthread.self = 4 **** v1 CLI RX|pthread.name = (pool_poolherder) **** v1 CLI RX|thr.req = NULL **** v1 CLI RX|thr.busyobj = NULL **** v1 CLI RX|thr.worker = NULL **** v1 CLI RX|vmods = { **** v1 CLI RX|}, **** v1 CLI RX|pools = { **** v1 CLI RX|}, **** v1 CLI RX| **** v1 CLI RX| **** dT 1.433 ---- v1 Unexpected panic * top failure during reset # top TEST ../../../../bin/vinyltest/tests/o00005.vtc FAILED (1.438) exit=2 FAIL tests/o00005.vtc (exit status: 2)